GO Logger 日志实践

分析一下用过的打印日志的log包

Go标准库自带log, 这个log的func比较少, 没有区分level, 但足够简单, 有prefix功能, 可以设置flag来控制时间格式, caller的文件名和行数, 其它的标准包如 net/http database/sql 等也用了此包.
对自带的log进行包装, 加入level, 颜色. 如ngaut/log, 这个log star数并不多, 还是从最近很火的一个项目pingcap/tidb里看到的, 有点小清新的感觉, 但这个log可能只是为tidb使用的, 缺少自带log的一些方法, 导致没法使用在一些可以定制logger的第三方库如gorm中. 于是我fork了一下https://github.com/hanjm/log, 增加了一些方法, 以便可以给gorm用.
完全自己实现的log, 结构化输出, 通常是key=value或json, 有名的有logrus, zap等. 第一次看到logrus感觉美极了, 于是大量使用, 直到在关注tidb的时候收到带日志的issues邮件, 里面的日志带了caller, 感觉很有用, 于是去搜logrus的issue看有没有这个功能, 搜到了一个issuehttps://github.com/sirupsen/logrus/issues/63, 讨论了三年这个功能还没加上, 只好放弃美丽的logrus, 找到了替代品zap, zap的设计非常好, 定制性强. log是经常调用的代码, 每次调用不可避免地要进行内存分配, 分配次数和每次分配的内存大小将影响性能. 对log内容的处理也是一个涉及到性能的点, 像log.Printf参数是interface{}, logrus的field是map[stirng]interface{}, 打印interface{}只能靠reflect, Go是静态强类型语言, 用反射的开销相对比较大, 所以zap使用了手动指定类型的方式, 从zap提供的benchmark上开看, 性能提升还是蛮大的, 虽然相比logrus使用起来更麻烦, 但为了性能, 还是值得的.

总结

为了方便进行日志分析, 统一用json行日志, 这样用elk时可以免去定制正则表达式存储到elasticSearch的field中.
net/http database/sql 及一些第三方包可能直接使用了标注库的log, 有个trick可以改变所有使用标准包log的行为, 通过log.SetOutput(w io.Writer)来改变位置, w是一个实现了Write(p []byte) (n int, err error)方法的io.Writer即可.
runtime.Caller可以得到调用者的pc, 文件名, 文件行数, runtime.FuncForPC(pc).Name()可以得到pc所在的函数名, 对于debug非常有帮助. 但有一定性能开销, 所以方案是: 对于http server的access log, 没有必要使用带caller的日志, 而对于http api具体实现的函数内的log, 有必要记录caller, 而且光有文件名和行数还不够, 毕竟改了代码行数就变了, 而函数名一般不会变, 带上函数名会更直观.
GitHub搜了一圈, 好多公司都会定制自己的log, 如tidb的ngaut/log, 七牛的qiniu/log, 饿了么的eleme/log, mailgun的mailgun/log, 是的, 我也造一个小轮子zaplog.zaplog是包装了zap, 带caller func name, 兼容logrus stdlog 的日志输出工具.

package zaplog

import (
	"bytes"
	"fmt"
	"go.uber.org/zap"
	"go.uber.org/zap/zapcore"
	"log"
	"runtime"
	"strings"
)

// CallerEncoder will add caller to log. format is "filename:lineNum:funcName", e.g:"zaplog/zaplog_test.go:15:zaplog.TestNewLogger"
func CallerEncoder(caller zapcore.EntryCaller, enc zapcore.PrimitiveArrayEncoder) {
	enc.AppendString(strings.Join([]string{caller.TrimmedPath(), runtime.FuncForPC(caller.PC).Name()}, ":"))
}

func newLoggerConfig(debugLevel bool) (loggerConfig zap.Config) {
	loggerConfig = zap.NewProductionConfig()
	loggerConfig.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder
	loggerConfig.EncoderConfig.EncodeCaller = CallerEncoder
	if debugLevel {
		loggerConfig.Level = zap.NewAtomicLevelAt(zap.DebugLevel)
	}
	return
}

// NewCustomLoggers is a shortcut to get normal logger, noCallerLogger.
func NewCustomLoggers(debugLevel bool) (logger, noCallerLogger *zap.Logger) {
	loggerConfig := newLoggerConfig(debugLevel)
	logger, err := loggerConfig.Build()
	if err != nil {
		panic(err)
	}
	loggerConfig.DisableCaller = true
	noCallerLogger, err = loggerConfig.Build()
	if err != nil {
		panic(err)
	}
	return
}

// NewLogger return a normal logger
func NewLogger(debugLevel bool) (logger *zap.Logger) {
	loggerConfig := newLoggerConfig(debugLevel)
	logger, err := loggerConfig.Build()
	if err != nil {
		panic(err)
	}
	return
}

// NewNoCallerLogger return a no caller key value, will be faster
func NewNoCallerLogger(debugLevel bool) (noCallerLogger *zap.Logger) {
	loggerConfig := newLoggerConfig(debugLevel)
	loggerConfig.DisableCaller = true
	noCallerLogger, err := loggerConfig.Build()
	if err != nil {
		panic(err)
	}
	return
}

// CompatibleLogger is a logger which compatible to logrus/std log/prometheus.
// it implements Print() Println() Printf() Dbug() Debugln() Debugf() Info() Infoln() Infof() Warn() Warnln() Warnf()
// Error() Errorln() Errorf() Fatal() Fataln() Fatalf() Panic() Panicln() Panicf() With() WithField() WithFields()
type CompatibleLogger struct {
	_log *zap.Logger
}

// NewCompatibleLogger return CompatibleLogger with caller field
func NewCompatibleLogger(debugLevel bool) *CompatibleLogger {
	return &CompatibleLogger{NewLogger(debugLevel).WithOptions(zap.AddCallerSkip(1))}
}

// Print logs a message at level Info on the compatibleLogger.
func (l CompatibleLogger) Print(args ...interface{}) {
	l._log.Info(fmt.Sprint(args...))
}

// Println logs a message at level Info on the compatibleLogger.
func (l CompatibleLogger) Println(args ...interface{}) {
	l._log.Info(fmt.Sprint(args...))
}

// Printf logs a message at level Info on the compatibleLogger.
func (l CompatibleLogger) Printf(format string, args ...interface{}) {
	l._log.Info(fmt.Sprintf(format, args...))
}

// Debug logs a message at level Debug on the compatibleLogger.
func (l CompatibleLogger) Debug(args ...interface{}) {
	l._log.Debug(fmt.Sprint(args...))
}

// Debugln logs a message at level Debug on the compatibleLogger.
func (l CompatibleLogger) Debugln(args ...interface{}) {
	l._log.Debug(fmt.Sprint(args...))
}

// Debugf logs a message at level Debug on the compatibleLogger.
func (l CompatibleLogger) Debugf(format string, args ...interface{}) {
	l._log.Debug(fmt.Sprintf(format, args...))
}

// Info logs a message at level Info on the compatibleLogger.
func (l CompatibleLogger) Info(args ...interface{}) {
	l._log.Info(fmt.Sprint(args...))
}

// Infoln logs a message at level Info on the compatibleLogger.
func (l CompatibleLogger) Infoln(args ...interface{}) {
	l._log.Info(fmt.Sprint(args...))
}

// Infof logs a message at level Info on the compatibleLogger.
func (l CompatibleLogger) Infof(format string, args ...interface{}) {
	l._log.Info(fmt.Sprintf(format, args...))
}

// Warn logs a message at level Warn on the compatibleLogger.
func (l CompatibleLogger) Warn(args ...interface{}) {
	l._log.Warn(fmt.Sprint(args...))
}

// Warnln logs a message at level Warn on the compatibleLogger.
func (l CompatibleLogger) Warnln(args ...interface{}) {
	l._log.Warn(fmt.Sprint(args...))
}

// Warnf logs a message at level Warn on the compatibleLogger.
func (l CompatibleLogger) Warnf(format string, args ...interface{}) {
	l._log.Warn(fmt.Sprintf(format, args...))
}

// Error logs a message at level Error on the compatibleLogger.
func (l CompatibleLogger) Error(args ...interface{}) {
	l._log.Error(fmt.Sprint(args...))
}

// Errorln logs a message at level Error on the compatibleLogger.
func (l CompatibleLogger) Errorln(args ...interface{}) {
	l._log.Error(fmt.Sprint(args...))
}

// Errorf logs a message at level Error on the compatibleLogger.
func (l CompatibleLogger) Errorf(format string, args ...interface{}) {
	l._log.Error(fmt.Sprintf(format, args...))
}

// Fatal logs a message at level Fatal on the compatibleLogger.
func (l CompatibleLogger) Fatal(args ...interface{}) {
	l._log.Fatal(fmt.Sprint(args...))
}

// Fatalln logs a message at level Fatal on the compatibleLogger.
func (l CompatibleLogger) Fatalln(args ...interface{}) {
	l._log.Fatal(fmt.Sprint(args...))
}

// Fatalf logs a message at level Fatal on the compatibleLogger.
func (l CompatibleLogger) Fatalf(format string, args ...interface{}) {
	l._log.Fatal(fmt.Sprintf(format, args...))
}

// Panic logs a message at level Painc on the compatibleLogger.
func (l CompatibleLogger) Panic(args ...interface{}) {
	l._log.Panic(fmt.Sprint(args...))
}

// Panicln logs a message at level Painc on the compatibleLogger.
func (l CompatibleLogger) Panicln(args ...interface{}) {
	l._log.Panic(fmt.Sprint(args...))
}

// Panicf logs a message at level Painc on the compatibleLogger.
func (l CompatibleLogger) Panicf(format string, args ...interface{}) {
	l._log.Panic(fmt.Sprintf(format, args...))
}

// With return a logger with an extra field.
func (l *CompatibleLogger) With(key string, value interface{}) *CompatibleLogger {
	return &CompatibleLogger{l._log.With(zap.Any(key, value))}
}

// WithField return a logger with an extra field.
func (l *CompatibleLogger) WithField(key string, value interface{}) *CompatibleLogger {
	return &CompatibleLogger{l._log.With(zap.Any(key, value))}
}

// WithFields return a logger with extra fields.
func (l *CompatibleLogger) WithFields(fields map[string]interface{}) *CompatibleLogger {
	i := 0
	var clog *CompatibleLogger
	for k, v := range fields {
		if i == 0 {
			clog = l.WithField(k, v)
		} else {
			clog = clog.WithField(k, v)
		}
		i++
	}
	return clog
}

// FormatStdLog set the output of stand package log to zaplog
func FormatStdLog() {
	log.SetFlags(log.Llongfile)
	log.SetOutput(&logWriter{NewNoCallerLogger(false)})
}

type logWriter struct {
	logger *zap.Logger
}

// Write implement io.Writer, as std log's output
func (w logWriter) Write(p []byte) (n int, err error) {
	i := bytes.Index(p, []byte(":")) + 1
	j := bytes.Index(p[i:], []byte(":")) + 1 + i
	caller := bytes.TrimRight(p[:j], ":")
	// find last index of /
	i = bytes.LastIndex(caller, []byte("/"))
	// find penultimate index of /
	i = bytes.LastIndex(caller[:i], []byte("/"))
	w.logger.Info("stdLog", zap.ByteString("caller", caller[i+1:]), zap.ByteString("log", bytes.TrimSpace(p[j:])))
	return len(p), nil
}